Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ensure correct log message from ETL overseer. #1490

Closed
wants to merge 1 commit into from

Conversation

jpwhite4
Copy link
Member

@jpwhite4 jpwhite4 commented Feb 2, 2021

The php type engine gets confused when you try to string convert an
iAction object in the Logger code. Possibly something to do with the way
the class is constructed or the loader????

Anyway the old code results in the iAction object being treated as an
Array like object in the classes/CCR/CCRLineFormatter.php on line 44.
This change ensures a string is sent to the logger since that is
what we want.

The php type engine gets confused when you try to string convert an
iAction object in the Logger code. Possibly something to do with the way
the class is constructed or the loader????

Anyway the old code results in the iAction object being treated as an
Array like object in the classes/CCR/CCRLineFormatter.php on line 44.
This change ensures a string is sent to the logger since that is
what we want.
@jpwhite4 jpwhite4 added the bug Bugfixes label Feb 2, 2021
@jpwhite4 jpwhite4 added this to the 9.5.0 milestone Feb 2, 2021
@ryanrath
Copy link
Contributor

ryanrath commented Feb 3, 2021

@jpwhite4

So I believe I've found the root problem that was causing this behavior. In \CCR\Logger.php::extractMessage starting at line 46:

 if (is_array($record)) {
   return json_encode($record);
}

This code is the reason that a PHP Warning about an Array to String conversion is thrown in CCRLineFormater::extractMessage on line 44 $nonMessageParts[] = "$key: $value";.


Here's an example:

Given the following logger call

$logger->info(array(
    'message'     => 'start',
    'action_name' => $actionName,
    'action'      => $actionObj,
    'start_date'  => $overseerOptions->getStartDate(),
    'end_date'    => $overseerOptions->getEndDate(),
));

the result of Logger::extractMessage looks like this:

{
   "message":"start",
   "action_name":"db-model-test.create-table",
   "action":{},
   "start_date":null,
   "end_date":null
}

Note the empty action object.

When this data get's to CCRLineFormatter::extractMessage as the value of $record['message']and is subsequently decoded on line 29 w/ json_decode($record['message'], true). The value of action is converted to an associative array due to the true argument passed to json_decode. Which ultimately is what causes the PHP Warning about converting an Array to string to be thrown on line 44.


So there's a couple of different ways I've thought of that we can fix this:

  • One is obviously the way you've presented here which definitely works.
  • Another would be to update Logger::extractMessage to look like this:
protected function extractMessage($record)
{
    if (is_array($record)) {
        while (list($key, $value) = each($record)) {
            if (is_object($value)) {
                $record[$key] = (string) $value;
            }
        }
        return json_encode($record);
    }
    return json_encode(array('message' => $record));
}

Thus making sure that we don't lose any information about objects that can be converted to strings.

  • And the last way to resolve this would be to implement the JsonSerializable interface for the ETL Action classes which would make sure that they produce the expected output when used in conjunction with json_encode.

Thoughts?

@ryanrath
Copy link
Contributor

ryanrath commented Feb 4, 2021

@jpwhite4 So a quick update, I was going back through the PHP7 & MariaDB updates and it turns out that, when running on Centos8, I need to include the changes to Logger::extractMessage to make sure that the component tests pass.

The problem I ran into was when running the DBModelTest component tests they all would error out with SQLSTATE[42000]: Syntax error or access violation: 1049 Unknown database 'test'. The reason for this particular error is that the function ( BaseETLTest::executeEtlAction) used to execute an ETL action was directly constructing / executing an ETL action object as opposed to using the ETL Overseer. And we only get the automatically create db functionality if we execute actions / pipelines via the ETL Overseer. Once I updated this function to utilize the overseer I started getting our good 'ol friend Array to string converstion error. I'm guessing it threw an error as opposed to just a warning due to PHP7 being more restrictive by default than PHP5.4. But needless to say I was able to resolve these new errors with the changes I mentioned above.

ryanrath pushed a commit to ryanrath/xdmod that referenced this pull request Feb 4, 2021
This change was necessary after running into a problem w/ running the component
tests on Centos8. Specifically, the DBModelTest tests began throwing a PHP error
for attempting to cast an array to string. Having run into this while testing /
researching ubccr#1490 I implemented one of the
proposed fixes for that PR here which resolved the errors.
ryanrath pushed a commit to ryanrath/xdmod that referenced this pull request Feb 8, 2021
We ran into a problem described in this PR:
ubccr#1490 After some research I found that the
root of the problem is this function json_encode'ing `$record` when the contents
of `$record` may contain objects that do not support `JsonSerializable` but that
do implement `toString()`. After a conversation w/ Joe it's been decided that
our Logging API will be to support the logging of arrays w/ objects that
implement a `toString()` function. The eagle-eyed may notice that this solution
differs from the one I put forth in the above PR. The reason being that the
original solution only supported the use case of having an array w/ top level
value objects and would not work as expected if a nested array is supplied with
an object that implements `toString()`.
@jpwhite4
Copy link
Member Author

This pull request is superseded by the #1493

@jpwhite4 jpwhite4 closed this Feb 10, 2021
ryanrath added a commit that referenced this pull request Feb 10, 2021
)

* Updating the logging code to not throw away all class information

We ran into a problem described in this PR:
#1490 After some research I found that the
root of the problem is this function json_encode'ing `$record` when the contents
of `$record` may contain objects that do not support `JsonSerializable` but that
do implement `toString()`. After a conversation w/ Joe it's been decided that
our Logging API will be to support the logging of arrays w/ objects that
implement a `toString()` function. The eagle-eyed may notice that this solution
differs from the one I put forth in the above PR. The reason being that the
original solution only supported the use case of having an array w/ top level
value objects and would not work as expected if a nested array is supplied with
an object that implements `toString()`.

* Adding Additional Documentation

Per @jpwhite4, it's important that we document that our Logger supports logging
both strings and arrays, and if an array is provided that contains objects,
those objects will be converted to strings via the `__toString` function.

Co-authored-by: Ryan Rathsam <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Bugfixes
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants